Add support for Go GC logging #196
Conversation
Codecov Report
@@ Coverage Diff @@
## develop #196 +/- ##
=============================================
+ Coverage 67.15% 67.18% +0.02%
- Complexity 1428 1434 +6
=============================================
Files 144 145 +1
Lines 8319 8354 +35
Branches 1335 1343 +8
=============================================
+ Hits 5587 5613 +26
- Misses 2161 2163 +2
- Partials 571 578 +7
Continue to review full report at Codecov.
|
|
Hi Roland
Interesting idea! I'll merge it soon.
Would you have some samplefile of the go gc log for me to see how this
looks like in GCViewer?
Best regards,
Jörg
|
The Go programming language has a very dense GC logging format, which is difficult to read for humans. It looks like this: gc 1 @0.027s 35%: 15+3.3+0.41 ms clock, 46+0.66/2.3/3.0+1.2 ms cpu... gc 2 @0.060s 28%: 3.6+7.6+0.37 ms clock, 10+0.33/0/6.5+1.1 ms cpu,... gc 3 @0.079s 26%: 0.072+6.7+0.68 ms clock, 0.21+3.9/0.060/11+2.0 m... gc 4 @0.104s 21%: 0.16+14+0.31 ms clock, 0.48+5.2/0.16/14+0.94 ms ... gc 5 @0.140s 18%: 0.12+14+0.73 ms clock, 0.36+3.8/4.1/16+2.1 ms cp... gc 6 @0.179s 17%: 0.20+15+0.48 ms clock, 0.62+5.1/10/19+1.4 ms cpu... gc 7 @0.222s 16%: 0.12+19+0.21 ms clock, 0.37+11/0.064/19+0.64 ms ... gc 8 @0.292s 15%: 0.10+13+0.34 ms clock, 0.32+10/11/13+1.0 ms cpu,... gc 9 @0.936s 4%: 0.053+25+0.67 ms clock, 0.16+0.30/0.36/30+2.0 ms ... gc 10 @1.123s 5%: 0.073+30+0.52 ms clock, 0.22+1.7/29/1.4+1.5 ms c... gc 11 @1.369s 4%: 0.066+34+0.47 ms clock, 0.19+10/20/2.1+1.4 ms cp... It fits well into the GCViewer model, although Go has nothing to do with the JVM.
|
I added an example log file to the test resources and also added a unit test for it. |
|
Ah, sorry - I have missed the sample file. Reading the unittests, I somehow managed to overlook the second test.
Thank you very much!
|
|
You didn't miss anything. I had just added the example file. |
| private AbstractGCEvent<?> parseMatch(Matcher matcher) { | ||
| double relativeTime = Double.parseDouble(matcher.group(2)); | ||
| double stopTheWorld1Time = Double.parseDouble(matcher.group(4)) / 1000.0; | ||
| double stopTheWorld2Time = Double.parseDouble(matcher.group(6)) / 1000.0; |
There was a problem hiding this comment.
Why are you only using groups 4 + 6 for the pause time? What is group 5?
There was a problem hiding this comment.
Group 5 is the "concurrent mark and scan". I left it out because I only considered the stop-the-world times relevant. Maybe I'm wrong, though. I was missing some Javadoc on the fields of the GCEvent class, therefore I could only guess what is important and what is not.
The full documentation is at https://golang.org/pkg/runtime/#hdr-Environment_Variables, the paragraph starting with gctrace:. I thought mentioning the above URL in the Javadoc would be sufficient. But sure, it wouldn't hurt to document each capturing group.
| public void test() throws IOException { | ||
| String gcLog = "" | ||
| + "gc starting...\n" // Such a line is not produced by the Go GC; it is just for testing | ||
| + "gc 1 @997.597s 3%: 68+0.36+0.51 ms clock, 205+0/16/89+1.5 ms cpu, 84->84->42 MB, 86 MB goal, 3 P\n" |
There was a problem hiding this comment.
So, the pause for this event is 68 + 0.51 ms. What about the 0.36 ms?
There was a problem hiding this comment.
The 0.36 ms is part of the GC time. I did not count it since I was only interested in the stop-the-world time. You can add it if you want. As I said above, the GC fields were not documented enough for me to decide which duration to include and which to omit.
|
Thank you very much! Documentation is indeed not overly well done.
I'll merge your pull request, when I find time.
Small note concerning the gc events in GCViewer: GCEvent is for stop the world events, ConcurrentGCEvent is for other events.
|
|
Finally! The pull request is merged and your name is added to the list of contributors. |
The Go programming language has a very dense GC logging format, which
is difficult to read for humans. It looks like this:
gc 1 @0.027s 35%: 15+3.3+0.41 ms clock, 46+0.66/2.3/3.0+1.2 ms cpu...
gc 2 @0.060s 28%: 3.6+7.6+0.37 ms clock, 10+0.33/0/6.5+1.1 ms cpu,...
gc 3 @0.079s 26%: 0.072+6.7+0.68 ms clock, 0.21+3.9/0.060/11+2.0 m...
gc 4 @0.104s 21%: 0.16+14+0.31 ms clock, 0.48+5.2/0.16/14+0.94 ms ...
gc 5 @0.140s 18%: 0.12+14+0.73 ms clock, 0.36+3.8/4.1/16+2.1 ms cp...
gc 6 @0.179s 17%: 0.20+15+0.48 ms clock, 0.62+5.1/10/19+1.4 ms cpu...
gc 7 @0.222s 16%: 0.12+19+0.21 ms clock, 0.37+11/0.064/19+0.64 ms ...
gc 8 @0.292s 15%: 0.10+13+0.34 ms clock, 0.32+10/11/13+1.0 ms cpu,...
gc 9 @0.936s 4%: 0.053+25+0.67 ms clock, 0.16+0.30/0.36/30+2.0 ms ...
gc 10 @1.123s 5%: 0.073+30+0.52 ms clock, 0.22+1.7/29/1.4+1.5 ms c...
gc 11 @1.369s 4%: 0.066+34+0.47 ms clock, 0.19+10/20/2.1+1.4 ms cp...
It fits well into the GCViewer model, although Go has nothing to do with
the JVM.